Skip to content

feat: make the provider request path observable - #2873

Merged
fseldow merged 1 commit into
notaryproject:mainfrom
charleswool:feat/request-logging
Aug 11, 2026
Merged

feat: make the provider request path observable#2873
fseldow merged 1 commit into
notaryproject:mainfrom
charleswool:feat/request-logging

Conversation

@charleswool

@charleswool charleswool commented Aug 5, 2026

Copy link
Copy Markdown
Contributor

Description

Note

This supersedes #2849, which is now closed. That PR was a 17-line prerequisite that this branch was stacked on; splitting them made both harder to review than a single PR, so they are merged here. This is now one commit against main with no stacking.

The v2 provider's request path is effectively silent. Compared to v1, an operator gets almost nothing to debug with:

v1 v2 (today)
Log calls in the verification code 233 (pkg/ + httpserver/) 54 (internal/, nearly all startup/lifecycle)
Log calls in the request handler 12+ per request 2 (both Warnf, only on a cache-write failure)
executor / store / cosign verifier 2 / 24 / 3 0 / 0 / 0

Two concrete holes:

  • A failed verification logs nothing at all. The error is placed into the Gatekeeper response (results[idx].Error = err.Error()) but never written to the pod log, so no valid executor configured, a registry auth failure, or a signature failure leaves no trace on the server side.
  • Both HTTP handlers discarded the error from verify/mutate (_ = s.verify(...)), so a body read, unmarshal or response-encoding failure produced an empty response and no log either.

Change

Trace IDs — attach a generated trace ID to each verify/mutate request context via logger.InitContext. It propagates to all context-aware downstream logging (executor, verifiers, auth providers, policy providers), so a single request's logs correlate.

Reading the trace ID from an incoming request header is supported by internal/logger but requires InitLogConfig to register the header names, which this binary does not call today. That can be wired up in a follow-up.

Request logging in internal/httpserver/handlers.go, all through the request-scoped logger so entries carry the trace ID and component-type:

  • error — verification failures, reference parse/resolve failures, and the handler-level errors that were previously discarded.
  • info — the per-artifact verification outcome, the key operational/audit signal (v1 logged the same). The message leads with succeeded=<bool> so a violation is greppable without parsing the JSON report. It runs once per artifact per request, whether the result was served from cache, recomputed, or shared via singleflight — it previously sat inside the singleflight closure, so a cache hit logged nothing and so did any caller deduplicated into another in-flight request.
  • debug — request start (artifact/reference count), cache hit/miss, resolved reference, and request duration.

System-error metric — count handler/processing failures with metrics.ReportSystemError, using stable, low-cardinality category labels (verify_artifact, mutate_parse_reference, mutate_resolve_reference) rather than the error text, so Prometheus label cardinality stays bounded. The full error is still returned to the caller and written to the log.

Example output that previously did not exist at all:

level=error msg="failed to handle the verification request: failed to unmarshal request body to provider request: ..." component-type=server trace-id=0d9a6926-d465-4a19-8217-8ce77b7c5484
level=error msg="failed to verify artifact1: no valid executor configured" component-type=server
level=info msg="verification result for registry.example/app:v1: succeeded=false, report={...}" component-type=server

This is deliberately scoped to the HTTP request path. Adding debug logging inside internal/executor, the verifiers and the stores (also currently at zero) is a sensible follow-up — see #2876 and #2877 for the credential/Key Vault half.

Testing

  • TestVerify_LogsFailures and TestResolveReference_LogsFailures assert the failure paths actually emit an error entry, so this can't silently regress. Assertions match on the test's own message via a shared findEntry helper rather than on log level alone, so a global hook cannot make them pass spuriously.
  • TestVerifyHandler_LogsFailure / TestMutateHandler_LogsFailure cover the previously discarded handler errors and assert the entry carries a trace ID.
  • TestVerify_LogsOutcomeOnCacheHit covers the warm-cache path; TestLogVerificationResult_Violation covers the violation message format.
  • go build ./..., go vet, package tests and golangci-lint pass. No go.mod change (logrus/hooks/test ships with logrus). ReportSystemError is nil-guarded, so it is a no-op when metrics are disabled.

Enable the debug logs with --set logger.level=debug (#2846).

Copilot AI lite review requested due to automatic review settings August 5, 2026 01:13
@github-actions github-actions Bot added the v2 label Aug 5, 2026

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR improves observability for the Gatekeeper provider request path by introducing request-scoped logging (including trace IDs) and emitting logs/metrics for verification and mutation outcomes and failure paths.

Changes:

  • Initialize a request context (trace ID) for verify/mutate handlers and use the request-scoped logger throughout the handler path.
  • Add debug/info/error logs around verification/mutation processing (cache hit/miss, resolved references, per-artifact outcomes, and failures) plus system-error metrics.
  • Add unit tests that assert error paths emit error-level logs; add metrics exporter flags/initialization wiring.

Reviewed changes

Copilot reviewed 5 out of 5 changed files in this pull request and generated 4 comments.

Show a summary per file
File Description
internal/httpserver/server.go Initializes request context (trace IDs) for verify/mutate handler entrypoints.
internal/httpserver/handlers.go Adds request-scoped logging and request duration/system-error metrics in verify/mutate/resolveReference.
internal/httpserver/handlers_test.go Adds tests asserting failure paths emit error logs via logrus hooks.
cmd/ratify-gatekeeper-provider/main.go Adds flags and wiring to optionally initialize the Prometheus metrics exporter.
cmd/ratify-gatekeeper-provider/main_test.go Updates tests for new metrics flags and validates metrics-init failures don’t become the returned error.
Suppressed comments (1)

internal/httpserver/handlers.go:82

  • The per-artifact info log happens inside the singleflight closure. If singleflight returns a shared result, the waiting caller won't emit the outcome log (it will only show up under the trace ID of the goroutine that executed the closure). Capture the returned shared flag and log the outcome for shared callers too so each request has a consistent audit signal.
			renderedResult := convertResult(result)
			if renderedResult != nil {
				log.Infof("verification result for %s: succeeded=%t", artifact, renderedResult.Succeeded)
			}

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread internal/httpserver/server.go
Comment thread internal/httpserver/handlers_test.go Outdated
Comment on lines +342 to +347
var logged bool
for _, entry := range hook.AllEntries() {
if entry.Level == logrus.ErrorLevel {
logged = true
}
}

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed in 84c9133. You're right that a global hook plus "any error entry" is a spurious-pass risk, and TestResolveReference_LogsFailures was the worst case since it asserted only on the level.

Added a shared helper that matches on the test's own message and returns on the first hit:

func findEntry(hook *test.Hook, level logrus.Level, want string) *logrus.Entry {
	for _, entry := range hook.AllEntries() {
		if entry.Level == level && strings.Contains(entry.Message, want) {
			return entry
		}
	}
	return nil
}

All the log assertions now go through it — artifact1 for the verify failure, !invalid! for the reference failure, and the artifact reference for the outcome logs. The hooks are also test.NewLocal(logrus.StandardLogger()) with defer hook.Reset() rather than test.NewGlobal().

Comment thread internal/httpserver/server.go
Comment thread internal/httpserver/handlers.go
@codecov

codecov Bot commented Aug 5, 2026

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 85.71429% with 5 lines in your changes missing coverage. Please review.
✅ Project coverage is 77.31%. Comparing base (5586aba) to head (12529ac).

Files with missing lines Patch % Lines
internal/httpserver/handlers.go 82.75% 4 Missing and 1 partial ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##             main    #2873      +/-   ##
==========================================
+ Coverage   77.10%   77.31%   +0.21%     
==========================================
  Files          90       90              
  Lines        4315     4343      +28     
==========================================
+ Hits         3327     3358      +31     
+ Misses        831      830       -1     
+ Partials      157      155       -2     

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

@charleswool
charleswool force-pushed the feat/request-logging branch from ece0cd9 to 84c9133 Compare August 10, 2026 04:25
The v2 request path is effectively silent. A failed verification logs
nothing at all: the error is placed into the Gatekeeper response but never
written to the pod log, so a missing executor, a registry auth failure or a
signature failure leaves no trace on the server side. Both HTTP handlers
also discarded the error from verify/mutate, so a malformed request body
produced an empty response and no log either.

Attach a generated trace ID to each verify/mutate request context via
logger.InitContext so every context-aware log downstream correlates, and log
through the request-scoped logger:

- error: verification failures and reference parse/resolve failures.
- info: the per-artifact verification outcome, led by succeeded=<bool> so a
  violation is greppable without parsing the JSON report. It runs once per
  artifact per request whether the result was cached, recomputed or shared
  via singleflight.
- debug: request start, cache hit/miss, resolved reference and duration.

Count handler failures with metrics.ReportSystemError using stable,
low-cardinality category labels rather than the error text, so Prometheus
label cardinality stays bounded. The full error is still returned to the
caller and written to the log.

Signed-off-by: Charles Wu <yuewu2@microsoft.com>
@charleswool
charleswool force-pushed the feat/request-logging branch from 84c9133 to 12529ac Compare August 11, 2026 00:31
@charleswool charleswool changed the title feat: log verification and mutation request outcomes feat: make the provider request path observable Aug 11, 2026
@fseldow
fseldow merged commit 85d579a into notaryproject:main Aug 11, 2026
21 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants